[DynamoDB] UserErrors が発生した場合に、その原因をCloudTrailで確認してみました

CloudTrailで「データイベント」を取得する証跡を作成して、メトリクスのタイムスタンプと照合することで、原因を特定する要領を確かめてみました。

#Amazon DynamoDB

#AWS CloudTrail

#Amazon CloudWatch

#AWS

SIN

2022.06.19

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

1 はじめに

IoT事業部の平内（SIN）です。

CloudWatchメトリクスで、UserErrorsのカウントが上がっているのを見つける事がありますが、こちらは、DynamoDB（または、DynamoDB Streams）へのリクエストにエラーがあったことを示しています。

下記のQAによると、実装等に何らかの問題ああって、ResourceNotFoundExceptionやValidationException などの例外が発生していることが原因とのことです。

Amazon DynamoDB テーブルに多数の UserErrors があるのはなぜですか?

しかし、メトリクスだけでは、テーブル名や、リクエストの内容までは、ちょっと分からないため、実装で例外が闇に葬られていたりすると、原因を見つけるのがちょっと難しくなる場合があります。

今回は、CloudTrailで「データイベント」を取得する証跡を作成して、メトリクスのタイムスタンプと照合することで、原因を特定する要領を確かめてみました。

2 Cloud Trail

CloudTrailで「データイベント」を取得する証跡を作成する要領は、以下の通りです。

新規に「証跡」を作成する

ClodWatch Logsを有効にします

対象のイベントは「データイベント」とし、「DynamoDB」のすべてのイベントを記録するようにしました。

3 サンプル（Lambda）

動作確認のためにサンプル用にLambdaを作成しました。テーブル（test-table）に１件書き込むだけの簡単なものです。

しかし、何らかの原因でテーブル名に誤りがあったりすると

table_name = "test-table-xxx"

ResourceNotFoundExceptionの例外が発生します。

Exception :An error occurred (ResourceNotFoundException) when calling the PutItem operation: Requested resource not found

また、アイテムの型を間違うとParameter validationとなります

item = {
    "id": {
        "N": 111
    }
}

Exception :Parameter validation failed:
Invalid type for parameter Item.id.N, value: 111, type: <class 'int'>, valid types: <class 'str'>

4 UserErrors

先のサンプルLambdaで、何回か例外を発生させてやると、UserErrorsメトリクスが観測されます。

ここで、統計を「合計」、期間を「１分」とする事で、分単位の「発生時間」と「件数」を得ることができます。ここでは、例として「2022-06-19 00:03(UTC) 3件」をサンプルしてみました。

5 Tool

サンプルは、下記のようなプログラムで簡単に集めることもできます。

import boto3
import datetime

# 現在時間から、過去、指定した日数分を取得する
start_time = datetime.datetime.now() - datetime.timedelta(days=1)
end_time = datetime.datetime.now()

# メトリクス取得
client = boto3.client('cloudwatch')
response = client.get_metric_data(
    MetricDataQueries=[
        {
            'Id': 'm1',
            'MetricStat': {
                'Metric': {
                    'Namespace': 'AWS/DynamoDB',
                    'MetricName': 'UserErrors'
                },
                'Period': 60,
                'Stat': 'Sum',
                'Unit': 'Count'
            },
        },
    ],
    StartTime=start_time,
    EndTime=end_time
)
data = response['MetricDataResults'][0]
timestamps = data["Timestamps"]
values = data["Values"]

print("[DynamoDB.UserErrors 集計]")
print("発生時間(JST)\t件数")
for i in range(len(values)):
    # 確認しやすいように日本時間に変換
    jst = timestamps[i] + datetime.timedelta(hours=9)
    print("{}\t{}".format(jst.strftime('%m-%d %H:%M'), int(values[i])))

実行結果です。

% python3 index.py
[DynamoDB.UserErrors 集計]
発生時間(JST)   件数
06-19 09:30 1
06-19 09:26 1
06-19 09:25 2
06-19 09:05 2
06-19 09:03 3  <= 09:03 JST（00:03 UTC）に3件発生していることが確認できる
06-19 09:02 1
06-19 09:01 1
06-19 08:58 1
06-19 08:57 1
06-19 08:38 1

6 原因の調査

CloudWatch Logsに出力されたログをInsightで検索すると、サンプルしたタイムスタンプと件数が一致しているログを確認できると思います。

fields @timestamp, @message
|sort eventTime desc
|filter eventSource = 'dynamodb.amazonaws.com'
|display eventTime,eventName,requestParameters.tableName,requestParameters.key.id,errorCode,errorMessage
| limit 200